From 8d4a005aa21376efe9a821b727682f8cbd194fb6 Mon Sep 17 00:00:00 2001 From: Nils Pukropp Date: Sat, 31 Oct 2026 09:54:07 +0100 Subject: [PATCH 1/3] fix(cli): give journald each log line's priority journald stored every daemon line at info, so journalctl -p warning, which TROUBLESHOOTING.md asks reporters for, was always empty (B258). When fd 1 is the journal stream, prefix lines with and drop colours. --- crates/pdfs-cli/src/journal.rs | 122 +++++++++++++++++++++++++++++++++ crates/pdfs-cli/src/main.rs | 27 +++++--- docs/BUGS.md | 15 ++-- 3 files changed, 151 insertions(+), 13 deletions(-) create mode 100644 crates/pdfs-cli/src/journal.rs diff --git a/crates/pdfs-cli/src/journal.rs b/crates/pdfs-cli/src/journal.rs new file mode 100644 index 0000000..a689a09 --- /dev/null +++ b/crates/pdfs-cli/src/journal.rs @@ -0,0 +1,122 @@ +//! Log priorities for journald. +//! +//! journald files each line a service writes at the unit's default priority, +//! info, unless the line opens with a syslog `` prefix. Without one every +//! WARN and ERROR the daemon logs is stored as info, and the +//! `journalctl -p warning` that the troubleshooting guide asks for shows +//! nothing (`docs/BUGS.md` B258). + +use std::fmt; +use std::os::unix::fs::MetadataExt; + +use tracing::{Event, Level, Subscriber}; +use tracing_subscriber::fmt::format::Writer; +use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields}; +use tracing_subscriber::registry::LookupSpan; + +/// Whether standard output is the journal stream systemd connected this +/// process to. +/// +/// `JOURNAL_STREAM` alone does not say so: a terminal started from a user unit +/// inherits it, and every `pdfs` run in that terminal would print the +/// prefixes. systemd sets it to the stream's `device:inode`, so it is compared +/// against what fd 1 actually is. +pub(crate) fn stdout_is_journal() -> bool { + let Some(stream) = std::env::var_os("JOURNAL_STREAM") else { + return false; + }; + let Ok(stdout) = std::fs::metadata("/proc/self/fd/1") else { + return false; + }; + stream + .to_str() + .is_some_and(|value| names_stream(value, stdout.dev(), stdout.ino())) +} + +/// Whether a `JOURNAL_STREAM` value names the file `dev`:`ino`. +fn names_stream(value: &str, dev: u64, ino: u64) -> bool { + value + .split_once(':') + .is_some_and(|(d, i)| d.parse() == Ok(dev) && i.parse() == Ok(ino)) +} + +/// The syslog priority journald should file a `level` line at. +fn priority(level: &Level) -> u8 { + match *level { + Level::ERROR => 3, + Level::WARN => 4, + Level::INFO => 6, + Level::DEBUG | Level::TRACE => 7, + } +} + +/// An event format that opens each line with its `` priority, then writes +/// the line as `F` would. +pub(crate) struct Prioritized(pub(crate) F); + +impl FormatEvent for Prioritized +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, + F: FormatEvent, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result { + write!(writer, "<{}>", priority(event.metadata().level()))?; + self.0.format_event(ctx, writer, event) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::io; + use std::sync::{Arc, Mutex}; + + #[derive(Clone)] + struct Buf(Arc>>); + + impl io::Write for Buf { + fn write(&mut self, bytes: &[u8]) -> io::Result { + self.0.lock().unwrap().extend_from_slice(bytes); + Ok(bytes.len()) + } + fn flush(&mut self) -> io::Result<()> { + Ok(()) + } + } + + #[test] + fn each_line_opens_with_the_priority_of_its_level() { + let buf = Buf(Arc::new(Mutex::new(Vec::new()))); + let writer = buf.clone(); + let subscriber = tracing_subscriber::fmt() + .with_max_level(Level::DEBUG) + .with_ansi(false) + .with_writer(move || writer.clone()) + .event_format(Prioritized(tracing_subscriber::fmt::format())) + .finish(); + tracing::subscriber::with_default(subscriber, || { + tracing::error!("e"); + tracing::warn!("w"); + tracing::info!("i"); + tracing::debug!("d"); + }); + let out = String::from_utf8(buf.0.lock().unwrap().clone()).unwrap(); + let prefixes: Vec<&str> = out.lines().map(|line| &line[..3]).collect(); + assert_eq!(prefixes, ["<3>", "<4>", "<6>", "<7>"]); + } + + #[test] + fn journal_stream_must_name_the_same_file() { + assert!(names_stream("8:12345", 8, 12345)); + assert!(!names_stream("8:12345", 8, 54321)); + assert!(!names_stream("9:12345", 8, 12345)); + assert!(!names_stream("8", 8, 12345)); + assert!(!names_stream("", 8, 12345)); + } +} diff --git a/crates/pdfs-cli/src/main.rs b/crates/pdfs-cli/src/main.rs index 75f6e3b..fa9b400 100644 --- a/crates/pdfs-cli/src/main.rs +++ b/crates/pdfs-cli/src/main.rs @@ -20,6 +20,8 @@ use pdfs_core::control::{ use pdfs_core::db::Db; use pdfs_core::service; +mod journal; + /// `println!` for this binary, shadowing std's, which panics when stdout is /// closed: `pdfs ls | head` ended in a "Broken pipe" panic once `head` had its /// lines. This one hands the failure to [`stdout_written`] instead. @@ -879,15 +881,22 @@ fn cli_error(kind: ErrorKind, message: &str) -> String { } fn main() -> Result<()> { - tracing_subscriber::fmt() - .with_env_filter( - tracing_subscriber::EnvFilter::try_from_default_env() - // `pgp` logs a benign WARN when it re-serializes a Proton secret-key - // packet with a longer (but equivalent) length encoding than the - // original; drop it to error so normal runs stay quiet. - .unwrap_or_else(|_| "info,pgp=error".into()), - ) - .init(); + let filter = tracing_subscriber::EnvFilter::try_from_default_env() + // `pgp` logs a benign WARN when it re-serializes a Proton secret-key + // packet with a longer (but equivalent) length encoding than the + // original; drop it to error so normal runs stay quiet. + .unwrap_or_else(|_| "info,pgp=error".into()); + if journal::stdout_is_journal() { + // journalctl colours lines by the priority the prefix gives them, so + // the escape codes would only be noise in the stored text. + tracing_subscriber::fmt() + .with_env_filter(filter) + .with_ansi(false) + .event_format(journal::Prioritized(tracing_subscriber::fmt::format())) + .init(); + } else { + tracing_subscriber::fmt().with_env_filter(filter).init(); + } let cli = Cli::parse(); JSON_OUTPUT.store(cli.json, std::sync::atomic::Ordering::Relaxed); diff --git a/docs/BUGS.md b/docs/BUGS.md index 319b4ca..55b86bd 100644 --- a/docs/BUGS.md +++ b/docs/BUGS.md @@ -83,7 +83,6 @@ original wording. | [B261](#b261--a-folder-that-has-never-synced-reads-up-to-date) | A folder that has never synced reads "up to date" | Not fixed | | [B260](#b260--the-poll-pushes-a-new-folders-first-sync-behind-every-other-folder) | The poll pushes a new folder's first sync behind every other folder | Not fixed | | [B259](#b259--the-sync-engine-can-die-or-hang-and-nothing-shows-it-until-a-restart) | The sync engine can die or hang, and nothing shows it until a restart | Not fixed; the trigger in #53 is not known | -| [B258](#b258--journalctl--p-warning-shows-nothing-whatever-the-daemon-logged) | `journalctl -p warning` shows nothing, whatever the daemon logged | Not fixed | | [B134](#b134--a-file-deleted-online-while-the-drain-checks-its-write-is-kept-as-a-conflict-copy) | A file deleted online while the drain checks its write is kept as a conflict copy | Only with `local_first` off | | [B91](#b91--the-daemon-hung-overnight-and-nothing-could-say-what-it-was-waiting-on) | The daemon hung overnight, and nothing could say what it was waiting on | The cause is not diagnosed; the daemon now reports where it is stuck and is restarted | | [B67](#b67--fresh-state-restore-can-silently-select-a-new-device-high-22) | Fresh-state restore can silently select a new device (HIGH-22) | An ambiguous device after a loss of local state is not asked about | @@ -116,6 +115,7 @@ a live account since. | Entry | Title | |---|---| +| [B258](#b258--journalctl--p-warning-shows-nothing-whatever-the-daemon-logged) | `journalctl -p warning` shows nothing, whatever the daemon logged | | [B256](#b256--pdfs-copy-right-after-a-save-copies-the-old-version) | `pdfs copy` right after a save copies the old version | | [B255](#b255--a-synced-folder-whose-files-are-all-gone-here-is-stuck-for-good) | A synced folder whose files are all gone here is stuck for good | | [B254](#b254--an-edit-in-the-same-second-as-a-new-upload-never-arrives) | An edit in the same second as a new upload never arrives | @@ -712,7 +712,7 @@ the pass age and the queue in `Diagnostics`. ### B258 — `journalctl -p warning` shows nothing, whatever the daemon logged -**Status:** Open +**Status:** Fixed, not verified live **Found:** 2026-10-31, issue #53: the reporter ran `journalctl --user -u proton-drive.service -b -p warning`, as `docs/TROUBLESHOOTING.md` tells them to, and got `-- No entries --`. **Where:** `main` in `crates/pdfs-cli/src/main.rs`; `packaging/proton-drive.service` @@ -725,8 +725,15 @@ stores every line of a service's output at the unit's default priority, info, un starts with a `` prefix. So every `WARN` and `ERROR` line is stored as info, and the troubleshooting guide's filter hides all of them. -**Fix.** Not done. When `JOURNAL_STREAM` says the output goes to journald, start each line with -the `` prefix for its level. +**Fix.** When standard output is the journal stream (`JOURNAL_STREAM` names the same +device and inode as fd 1), each line starts with the `` prefix for its level, and ANSI colours +are off. A terminal that merely inherited `JOURNAL_STREAM` keeps the plain format +(`crates/pdfs-cli/src/journal.rs`). + +**Test:** `each_line_opens_with_the_priority_of_its_level` and +`journal_stream_must_name_the_same_file` in `pdfs-cli`. On 2026-10-31, `pdfs diagnose` run with +`RUST_LOG=debug` under `systemd-run --user -p StandardOutput=journal` stored its debug lines at +`PRIORITY=7` and its report at 6. --- From c64bb23e3c8e55a5a3a51dd29ac825f964c062fb Mon Sep 17 00:00:00 2001 From: Nils Pukropp Date: Sat, 31 Oct 2026 10:14:23 +0100 Subject: [PATCH 2/3] fix(fuse,core,cli): keep a panicking sync pass from ending the engine One thread runs every synced folder's passes. A panic in a pass ended it, and every later add, sync-now, file event and poll went nowhere without a word until a restart, which fits issue #53 (B259). Each pass now runs under catch_unwind; a panic sets the folder to error and the next poll tries again. Diagnostics reports the engine's state, the supervisor warns when it has ended or a pass has gone quiet, and first passes log at info. --- crates/pdfs-cli/src/main.rs | 21 +++++ crates/pdfs-core/src/control.rs | 23 +++++ crates/pdfs-fuse/src/diagnostics.rs | 1 + crates/pdfs-fuse/src/lib.rs | 3 + crates/pdfs-fuse/src/mount.rs | 1 + crates/pdfs-fuse/src/supervisor.rs | 68 +++++++++++++- crates/pdfs-fuse/src/sync.rs | 73 ++++++++++++++- crates/pdfs-fuse/src/sync/engine.rs | 132 ++++++++++++++++++++++++++-- docs/BUGS.md | 26 ++++-- 9 files changed, 334 insertions(+), 14 deletions(-) diff --git a/crates/pdfs-cli/src/main.rs b/crates/pdfs-cli/src/main.rs index 75f6e3b..b0b7e49 100644 --- a/crates/pdfs-cli/src/main.rs +++ b/crates/pdfs-cli/src/main.rs @@ -3096,6 +3096,24 @@ fn human_secs(secs: u64) -> String { } } +/// The sync engine's line in `pdfs diagnostics`: whether it runs, and which +/// folder's pass it is on. +fn sync_engine_line(sync: &pdfs_core::control::SyncEngineState) -> String { + let mut line = match (sync.running, sync.pass_folder) { + (false, _) => "STOPPED; synced folders do not sync until the daemon restarts".to_string(), + (true, None) => "idle".to_string(), + (true, Some(folder)) => format!( + "pass on folder {folder} for {}, last progress {} ago", + human_secs(sync.pass_age_secs), + human_secs(sync.pass_idle_secs), + ), + }; + if sync.panics > 0 { + line.push_str(&format!("; {} pass(es) panicked", sync.panics)); + } + line +} + fn cmd_diagnostics() -> Result<()> { let response = control_request(CtlRequest::Diagnostics)?; if emit_json(&response)? { @@ -3131,6 +3149,9 @@ fn cmd_diagnostics() -> Result<()> { human_secs(worker.age_secs) ); } + if let Some(sync) = &d.sync { + println!("sync engine: {}", sync_engine_line(sync)); + } if d.inflight.is_empty() { println!("in-flight requests: none"); } else { diff --git a/crates/pdfs-core/src/control.rs b/crates/pdfs-core/src/control.rs index c111146..3b7c590 100644 --- a/crates/pdfs-core/src/control.rs +++ b/crates/pdfs-core/src/control.rs @@ -1980,6 +1980,29 @@ pub struct Diagnostics { pub control_handler_limit: usize, /// Queued mutations not yet drained. pub pending_ops: u64, + /// The folder-sync engine. `None` from a daemon that predates the field. + #[serde(default)] + pub sync: Option, +} + +/// What the folder-sync engine is doing, for [`Diagnostics`]. +/// +/// The engine is one thread that runs every synced folder's passes in turn. +/// Dead or stuck, it looked exactly like an idle one: workers idle, nothing +/// queued, nothing in the journal (`docs/BUGS.md` B259). +#[derive(Serialize, Deserialize, Debug, Clone, Default)] +pub struct SyncEngineState { + /// Whether the engine thread is running. Once it has ended, nothing syncs + /// until the daemon restarts. + pub running: bool, + /// The synced folder whose pass is running, if one is. + pub pass_folder: Option, + /// How long that pass has been running. + pub pass_age_secs: u64, + /// How long since that pass last reported progress. + pub pass_idle_secs: u64, + /// Passes that ended in a panic since the daemon started. + pub panics: u64, } /// The daemon's reply to a [`Request`]. diff --git a/crates/pdfs-fuse/src/diagnostics.rs b/crates/pdfs-fuse/src/diagnostics.rs index 5cde5df..f775043 100644 --- a/crates/pdfs-fuse/src/diagnostics.rs +++ b/crates/pdfs-fuse/src/diagnostics.rs @@ -163,6 +163,7 @@ impl Core { control_handlers: super::control::active_handlers(), control_handler_limit: super::control::handler_limit(), pending_ops: self.pending_ops_quickly(), + sync: Some(self.sync_engine.report()), } } diff --git a/crates/pdfs-fuse/src/lib.rs b/crates/pdfs-fuse/src/lib.rs index d9bbb0e..bb7f004 100644 --- a/crates/pdfs-fuse/src/lib.rs +++ b/crates/pdfs-fuse/src/lib.rs @@ -728,6 +728,8 @@ struct Core { /// can say what a pass is doing rather than just "syncing". An entry exists /// only while that folder's reconcile pass is running. sync_progress: Arc>>, + /// Whether the folder-sync engine is alive, and which pass it is on. + sync_engine: Arc, /// Channel to the folder-sync engine: nudges it to /// reconcile a folder, reconcile everything, or re-scan its watch set. sync_tx: std::sync::mpsc::Sender, @@ -5989,6 +5991,7 @@ impl Core { if let Some(p) = self.sync_progress.lock().get_mut(&folder_id) { f(p); } + self.sync_engine.moved(); } /// Set the number of items the scan expects to check, from the size of the diff --git a/crates/pdfs-fuse/src/mount.rs b/crates/pdfs-fuse/src/mount.rs index 1aeccdc..f60a1e3 100644 --- a/crates/pdfs-fuse/src/mount.rs +++ b/crates/pdfs-fuse/src/mount.rs @@ -507,6 +507,7 @@ pub(crate) fn mount_with( events: Arc::new(Default::default()), indexing: Arc::new(AtomicBool::new(false)), sync_progress: Arc::new(Mutex::new(HashMap::new())), + sync_engine: Arc::default(), sync_tx, mounts: Arc::new(Mutex::new(SecondaryMountRegistry::default())), sync_locks: Arc::new(Mutex::new(HashMap::new())), diff --git a/crates/pdfs-fuse/src/supervisor.rs b/crates/pdfs-fuse/src/supervisor.rs index c7cfdf3..6e54f87 100644 --- a/crates/pdfs-fuse/src/supervisor.rs +++ b/crates/pdfs-fuse/src/supervisor.rs @@ -36,6 +36,11 @@ const TICK: Duration = Duration::from_secs(15); /// would train everyone to ignore the real one. const STALL_AFTER: Duration = Duration::from_secs(120); +/// How long a sync pass may go without reporting progress before it is called +/// out. Much longer than [`STALL_AFTER`]: one large file in a pass reports +/// nothing until its whole transfer is done. +const SYNC_STALL_AFTER: Duration = Duration::from_secs(900); + /// How often resident size goes into the log. const RSS_EVERY: Duration = Duration::from_secs(300); @@ -137,6 +142,26 @@ fn report_stalls(report: &pdfs_core::control::Diagnostics, last_completed: (u64, "the transfer lane has not completed a job since the last check" ); } + // The engine is one thread for every synced folder, so a dead or stuck one + // stops all of them while the worker pool looks idle (B259). + if let Some(sync) = &report.sync { + if !sync.running { + stalled = true; + warn!( + "the sync engine is not running; synced folders do not sync until the daemon restarts" + ); + } else if let Some(folder) = sync.pass_folder + && sync.pass_idle_secs >= SYNC_STALL_AFTER.as_secs() + { + stalled = true; + warn!( + folder, + age_secs = sync.pass_age_secs, + idle_secs = sync.pass_idle_secs, + "a sync pass has not reported progress for a long time" + ); + } + } stalled } @@ -169,7 +194,7 @@ fn probe(control_socket: &Path) -> bool { #[cfg(test)] mod tests { use super::*; - use pdfs_core::control::{Diagnostics, InflightRequest, WorkerState}; + use pdfs_core::control::{Diagnostics, InflightRequest, SyncEngineState, WorkerState}; fn busy_worker(age_secs: u64) -> WorkerState { WorkerState { @@ -226,4 +251,45 @@ mod tests { assert!(!report_stalls(&report, (0, 30))); assert!(report_stalls(&report, (0, 40))); } + + fn with_sync(sync: SyncEngineState) -> Diagnostics { + Diagnostics { + sync: Some(sync), + ..Default::default() + } + } + + /// A sync engine that has ended stops every synced folder while the + /// workers look idle, which is what issue #53 looked like (B259). + #[test] + fn a_stopped_sync_engine_is_a_stall() { + assert!(report_stalls( + &with_sync(SyncEngineState::default()), + (0, 0) + )); + } + + /// A pass that keeps reporting progress is working, however long it runs; + /// one that has gone quiet past the threshold is not. + #[test] + fn only_a_quiet_sync_pass_is_a_stall() { + let busy = SyncEngineState { + running: true, + pass_folder: Some(3), + pass_age_secs: SYNC_STALL_AFTER.as_secs() * 4, + pass_idle_secs: 5, + panics: 0, + }; + assert!(!report_stalls(&with_sync(busy.clone()), (0, 0))); + let quiet = SyncEngineState { + pass_idle_secs: SYNC_STALL_AFTER.as_secs(), + ..busy + }; + assert!(report_stalls(&with_sync(quiet), (0, 0))); + let idle = SyncEngineState { + running: true, + ..Default::default() + }; + assert!(!report_stalls(&with_sync(idle), (0, 0))); + } } diff --git a/crates/pdfs-fuse/src/sync.rs b/crates/pdfs-fuse/src/sync.rs index 864e522..c698021 100644 --- a/crates/pdfs-fuse/src/sync.rs +++ b/crates/pdfs-fuse/src/sync.rs @@ -48,8 +48,10 @@ mod engine; mod local_scan; mod model; mod planner; +#[cfg(test)] +use engine::Running; pub(crate) use engine::SYNC_CONCURRENCY; -pub(crate) use engine::{SyncMsg, spawn}; +pub(crate) use engine::{EngineHealth, SyncMsg, spawn}; #[cfg(test)] use engine::{classify, event_target, settle_with}; #[cfg(test)] @@ -67,6 +69,11 @@ use planner::{ plan_file, rel_to_path, remote_sig, remote_subtree_changed, revision_moved, tracked_baseline, unchanged_remote_size, }; + +/// A pass that took at least this long is logged at info even when it changed +/// nothing, so the journal says where a slow engine spends its time. +const SLOW_PASS: Duration = Duration::from_secs(30); + /// What a [`Pending`] op did, so the reconcile can update shared state on the /// engine thread (never inside a task). enum Applied { @@ -154,6 +161,14 @@ impl Core { // The cost is one small file read against a pass that is about to walk the // whole tree. let rules = self.ignore_rules(&local_root); + // A first pass is the one a user waits on after adding or restoring a + // folder, so it is said at info; the poll's passes stay at debug. + if folder.last_sync == 0 { + info!(id = folder.id, path = %folder.local_path, "sync: first pass starting"); + } else { + debug!(id = folder.id, "sync: pass starting"); + } + let started = Instant::now(); self.progress_begin(folder.id); let result = if push_only { self.push_pass(folder.id, &local_root, &remote_root, &rules) @@ -195,6 +210,18 @@ impl Core { "idle" }; let _ = self.db.sync_folder_set_state(folder.id, state, now_secs()); + let elapsed = started.elapsed(); + if folder.last_sync == 0 || !outcome.is_empty() || elapsed >= SLOW_PASS { + info!( + id = folder.id, + state, + elapsed_ms = elapsed.as_millis() as u64, + summary = %outcome.summary(), + "sync: pass finished" + ); + } else { + debug!(id = folder.id, state, "sync: pass finished"); + } self.report_unscanned(folder.id, name, &outcome.unscanned); // Summarise a pass that actually moved something. A poll over an // unchanged folder does nothing and says nothing — otherwise the @@ -2438,6 +2465,50 @@ fn system_mtime_ns(meta: &std::fs::Metadata) -> Option { mod tests { use super::*; + /// A panic in a pass ends that pass and is counted; the engine is not + /// left believing the pass still runs (`docs/BUGS.md` B259). + #[test] + fn a_panicking_pass_is_contained_and_counted() { + let health = EngineHealth::default(); + assert!(!health.contain(7, || panic!("a pass that panics"))); + let report = health.report(); + assert_eq!(report.panics, 1); + assert_eq!(report.pass_folder, None); + assert!(health.contain(7, || {})); + assert_eq!(health.report().panics, 1); + } + + /// While a pass runs, the report names its folder, which is what tells a + /// long pass apart from an idle engine. + #[test] + fn the_running_pass_is_reported() { + let health = EngineHealth::default(); + let mut seen = None; + health.contain(7, || seen = health.report().pass_folder); + assert_eq!(seen, Some(7)); + } + + /// The engine reads as running only while its thread lives, including + /// when the thread ends in a panic. + #[test] + fn the_engine_reads_as_stopped_once_its_thread_ends() { + let health = Arc::new(EngineHealth::default()); + let thread_health = health.clone(); + let (started_tx, started_rx) = std::sync::mpsc::channel(); + let (end_tx, end_rx) = std::sync::mpsc::channel::<()>(); + let thread = std::thread::spawn(move || { + let _running = Running::start(&thread_health); + started_tx.send(()).unwrap(); + let _ = end_rx.recv(); + panic!("the engine thread panics"); + }); + started_rx.recv().unwrap(); + assert!(health.report().running); + end_tx.send(()).unwrap(); + assert!(thread.join().is_err()); + assert!(!health.report().running); + } + /// A removal of something already gone has produced the state the sync /// engine wanted, so its baseline is dropped rather than retried forever. /// Anything else stays an error and keeps the baseline (`docs/BUGS.md` B42). diff --git a/crates/pdfs-fuse/src/sync/engine.rs b/crates/pdfs-fuse/src/sync/engine.rs index 5664392..7020cb4 100644 --- a/crates/pdfs-fuse/src/sync/engine.rs +++ b/crates/pdfs-fuse/src/sync/engine.rs @@ -1,5 +1,11 @@ //! Filesystem watcher, polling, and debounce control plane. +use std::panic::AssertUnwindSafe; +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; + +use pdfs_core::control::SyncEngineState; +use tracing::error; + use super::*; /// How long the watcher must go quiet before a burst counts as finished. @@ -53,8 +59,124 @@ pub(crate) fn spawn(core: Core, rx: Receiver) -> Option>, + panics: AtomicU64, +} + +#[derive(Clone, Copy)] +struct PassClock { + folder: i64, + started: Instant, + moved: Instant, +} + +impl EngineHealth { + /// Note that the running pass reported progress. + pub(crate) fn moved(&self) { + if let Some(pass) = self.pass.lock().as_mut() { + pass.moved = Instant::now(); + } + } + + /// The engine's state now. `try_lock`, like the rest of the diagnostics: + /// a report must not wait on the thing it reports about. + pub(crate) fn report(&self) -> SyncEngineState { + let pass = self.pass.try_lock().and_then(|pass| *pass); + SyncEngineState { + running: self.running.load(Ordering::Relaxed), + pass_folder: pass.map(|p| p.folder), + pass_age_secs: pass.map_or(0, |p| p.started.elapsed().as_secs()), + pass_idle_secs: pass.map_or(0, |p| p.moved.elapsed().as_secs()), + panics: self.panics.load(Ordering::Relaxed), + } + } + + /// Run `pass` over `folder` as the current pass. Returns `false` when it + /// panicked: the panic ends that pass, not the engine. + pub(super) fn contain(&self, folder: i64, pass: impl FnOnce()) -> bool { + let now = Instant::now(); + *self.pass.lock() = Some(PassClock { + folder, + started: now, + moved: now, + }); + let finished = std::panic::catch_unwind(AssertUnwindSafe(pass)).is_ok(); + *self.pass.lock() = None; + if !finished { + self.panics.fetch_add(1, Ordering::Relaxed); + } + finished + } +} + +/// Marks the engine running for as long as it lives. +pub(super) struct Running<'a>(&'a EngineHealth); + +impl<'a> Running<'a> { + pub(super) fn start(health: &'a EngineHealth) -> Self { + health.running.store(true, Ordering::Relaxed); + Self(health) + } +} + +impl Drop for Running<'_> { + fn drop(&mut self) { + self.0.running.store(false, Ordering::Relaxed); + if std::thread::panicking() { + error!("sync engine stopped by a panic; nothing syncs until the daemon restarts"); + } + } +} + +/// One folder's pass, contained: a panic in it sets the folder to `error` and +/// leaves the engine running for the next one. +fn run_pass(core: &Core, folder: &StoredSyncFolder) { + if core + .sync_engine + .contain(folder.id, || core.reconcile_folder(folder)) + { + return; + } + core.progress_end(folder.id); + let _ = core + .db + .sync_folder_set_state(folder.id, "error", folder.last_sync); + error!( + id = folder.id, + path = %folder.local_path, + "sync: pass panicked; the folder is set to error and tried again on the next poll" + ); + core.log_activity( + ActivityKind::Sync, + format!("sync failed for {}", base_name(&folder.local_path)), + "an internal error stopped the pass; it is tried again on the next poll", + false, + ); +} + +/// The pass a `Reconcile(id)` asked for. A folder removed since, or one the +/// database cannot read, is said so rather than dropped in silence. +fn run_pass_by_id(core: &Core, id: i64) { + match core.db.sync_folder_get(id) { + Ok(Some(folder)) => run_pass(core, &folder), + Ok(None) => debug!(id, "sync: folder removed before its pass; skipping"), + Err(e) => warn!(id, error = ?e, "sync: cannot read folder; skipping its pass"), + } +} + /// The engine control loop. Single-threaded so reconcile passes never overlap. fn engine_loop(core: Core, rx: Receiver) { + let health = core.sync_engine.clone(); + let _running = Running::start(&health); // Paths the watcher currently covers, mapped to their folder id, so an event // path can be resolved back to the folder it belongs to. let watched: Arc>> = Arc::new(Mutex::new(Vec::new())); @@ -120,9 +242,7 @@ fn engine_loop(core: Core, rx: Receiver) { if core.sync_paused() { break; } - if let Ok(Some(folder)) = core.db.sync_folder_get(id) { - core.reconcile_folder(&folder); - } + run_pass_by_id(&core, id); } } } @@ -159,9 +279,7 @@ fn poll_only_loop(core: &Core, rx: Receiver) { if core.sync_paused() { break; } - if let Ok(Some(folder)) = core.db.sync_folder_get(id) { - core.reconcile_folder(&folder); - } + run_pass_by_id(core, id); } } } @@ -254,7 +372,7 @@ fn reconcile_all(core: &Core) { } }; for folder in folders { - core.reconcile_folder(&folder); + run_pass(core, &folder); } } diff --git a/docs/BUGS.md b/docs/BUGS.md index 319b4ca..2103de3 100644 --- a/docs/BUGS.md +++ b/docs/BUGS.md @@ -82,7 +82,6 @@ original wording. | [B262](#b262--watching-a-large-synced-folder-holds-up-the-sync-engine-and-a-failed-watch-is-never-retried) | Watching a large synced folder holds up the sync engine, and a failed watch is never retried | Not fixed | | [B261](#b261--a-folder-that-has-never-synced-reads-up-to-date) | A folder that has never synced reads "up to date" | Not fixed | | [B260](#b260--the-poll-pushes-a-new-folders-first-sync-behind-every-other-folder) | The poll pushes a new folder's first sync behind every other folder | Not fixed | -| [B259](#b259--the-sync-engine-can-die-or-hang-and-nothing-shows-it-until-a-restart) | The sync engine can die or hang, and nothing shows it until a restart | Not fixed; the trigger in #53 is not known | | [B258](#b258--journalctl--p-warning-shows-nothing-whatever-the-daemon-logged) | `journalctl -p warning` shows nothing, whatever the daemon logged | Not fixed | | [B134](#b134--a-file-deleted-online-while-the-drain-checks-its-write-is-kept-as-a-conflict-copy) | A file deleted online while the drain checks its write is kept as a conflict copy | Only with `local_first` off | | [B91](#b91--the-daemon-hung-overnight-and-nothing-could-say-what-it-was-waiting-on) | The daemon hung overnight, and nothing could say what it was waiting on | The cause is not diagnosed; the daemon now reports where it is stuck and is restarted | @@ -96,6 +95,7 @@ original wording. | Entry | Title | What is left | |---|---|---| +| [B259](#b259--the-sync-engine-can-die-or-hang-and-nothing-shows-it-until-a-restart) | The sync engine can die or hang, and nothing shows it until a restart | No pass deadline; an ended engine is reported, not restarted; the trigger in #53 is not known | | [B199](#b199--a-stopped-share-stays-on-the-shared-by-me-page-for-minutes) | A stopped share stays on the Shared by me page for minutes | The share itself is not deleted; the SDK has no call for it | | [B88](#b88--pdfs-pin-rename-move-delete-and-sharing-still-cannot-name-a-path-under-a-secondary-mount) | `pdfs pin`, `rename`, `move`, `delete` and sharing still cannot name a path under a secondary mount | `pin`, `unpin`, opening a file, thumbnails, uploads, sharing and versions | | [B72](#b72--pdfs-trash-never-returns) | `pdfs trash` never returns | The slowness of the first refresh is unmeasured | @@ -680,7 +680,8 @@ while a pass runs. ### B259 — The sync engine can die or hang, and nothing shows it until a restart -**Status:** Open +**Status:** Partly fixed. A hung pass is reported but not ended, and a panic outside a pass +still stops the engine; it is reported, not restarted. **Found:** 2026-10-31, issue #53: a newly added folder did not sync until the reporter restarted the app. All FUSE workers were idle, nothing was queued, and the warning-level journal was empty (B258). @@ -704,9 +705,24 @@ is why it helps. nothing about sync. - A database error when the engine reads a folder drops that folder's request without a log. -**Fix.** Not done. Catch a panic per pass, end its progress and set the folder to `error`. Have -the supervisor restart a finished engine thread. Log passes at info, and report the folder, -the pass age and the queue in `Diagnostics`. +**Fix.** +- Each pass runs under `catch_unwind` (`EngineHealth::contain` in + `crates/pdfs-fuse/src/sync/engine.rs`). A panic ends that pass only: its progress is cleared, + the folder is set to `error`, the activity feed says so, and the next poll tries again. +- `Diagnostics` carries the engine's state: running or not, the folder of the running pass, how + long it has run and how long since it last reported progress, and how many passes panicked. + `pdfs diagnostics` prints it as `sync engine: …`. +- The supervisor warns when the engine thread has ended, and when a pass has reported no + progress for 15 minutes. +- A first pass logs its start and end at info, as does any pass that changed something or + took 30 s or more. A request for a folder the database cannot read is logged. +- Not done: a deadline for a pass, and restarting an engine thread that has ended. The + channel's receiver ends with the thread, so a restart needs a new channel in every `Core` + clone. + +**Test:** `a_panicking_pass_is_contained_and_counted`, `the_running_pass_is_reported` and +`the_engine_reads_as_stopped_once_its_thread_ends` in `pdfs-fuse`; +`a_stopped_sync_engine_is_a_stall` and `only_a_quiet_sync_pass_is_a_stall` in the supervisor. --- From b40ca797d9900cf2999199c6a62bbb17c3ca2cf4 Mon Sep 17 00:00:00 2001 From: Nils Pukropp Date: Sat, 31 Oct 2026 10:24:32 +0100 Subject: [PATCH 3/3] fix(fuse): run a burst's named folders first and retry failed watches A poll in the same burst as a new folder's Reconcile(id) took its place, so the new folder waited behind a pass over every other one (B260). A recursive watch that failed partway left its watches registered, was never retried, and its events ran passes over every folder (B262). It is now unwatched and retried every 10 minutes, symlinks are not followed, and watcher errors are logged. A folder removed and added again in one burst keeps its watch under the new id (B272). --- crates/pdfs-fuse/src/sync.rs | 26 +++- crates/pdfs-fuse/src/sync/engine.rs | 199 ++++++++++++++++++---------- docs/BUGS.md | 38 ++++-- 3 files changed, 181 insertions(+), 82 deletions(-) diff --git a/crates/pdfs-fuse/src/sync.rs b/crates/pdfs-fuse/src/sync.rs index c698021..a5c5f09 100644 --- a/crates/pdfs-fuse/src/sync.rs +++ b/crates/pdfs-fuse/src/sync.rs @@ -48,11 +48,11 @@ mod engine; mod local_scan; mod model; mod planner; -#[cfg(test)] -use engine::Running; pub(crate) use engine::SYNC_CONCURRENCY; pub(crate) use engine::{EngineHealth, SyncMsg, spawn}; #[cfg(test)] +use engine::{Running, burst_order, keep_wanted}; +#[cfg(test)] use engine::{classify, event_target, settle_with}; #[cfg(test)] use local_scan::is_write_mode; @@ -2478,6 +2478,28 @@ mod tests { assert_eq!(health.report().panics, 1); } + /// Folders named by id run before the rest of a `ReconcileAll` in the + /// same burst, so a folder just added does not wait behind a pass over + /// every other folder (`docs/BUGS.md` B260). + #[test] + fn named_folders_run_before_the_rest_of_a_burst() { + let ids: HashSet = [9, 4].into(); + assert_eq!(burst_order(&ids, &[1, 4, 6, 9]), [4, 9, 1, 6]); + assert_eq!(burst_order(&HashSet::new(), &[1, 4]), [1, 4]); + // A folder the list no longer has still gets the pass it asked for. + assert_eq!(burst_order(&[12].into(), &[1]), [12, 1]); + } + + /// A folder removed and added again keeps its watch under the new id; + /// a folder that is gone loses its watch (`docs/BUGS.md` B272). + #[test] + fn a_re_added_folder_keeps_its_watch_under_the_new_id() { + let mut have = vec![(PathBuf::from("/a"), 1), (PathBuf::from("/b"), 2)]; + let dropped = keep_wanted(&mut have, &[(PathBuf::from("/a"), 7)]); + assert_eq!(have, [(PathBuf::from("/a"), 7)]); + assert_eq!(dropped, [PathBuf::from("/b")]); + } + /// While a pass runs, the report names its folder, which is what tells a /// long pass apart from an idle engine. #[test] diff --git a/crates/pdfs-fuse/src/sync/engine.rs b/crates/pdfs-fuse/src/sync/engine.rs index 7020cb4..8d6fb00 100644 --- a/crates/pdfs-fuse/src/sync/engine.rs +++ b/crates/pdfs-fuse/src/sync/engine.rs @@ -29,6 +29,9 @@ const POLL_INTERVAL: Duration = Duration::from_secs(120); /// unusable done one-at-a-time; this bounds concurrency like the bulk-upload /// engine does. pub(crate) const SYNC_CONCURRENCY: usize = 8; +/// How long after a failed watch the engine tries the watches again. Each try +/// walks the folder's whole tree, so not on every burst. +const REWATCH_RETRY: Duration = Duration::from_secs(600); /// A message to the sync engine's control thread. pub(crate) enum SyncMsg { @@ -183,24 +186,35 @@ fn engine_loop(core: Core, rx: Receiver) { let tx_events = core.sync_tx.clone(); let watched_events = watched.clone(); - let mut watcher = - match notify::recommended_watcher(move |res: notify::Result| { - let Ok(event) = res else { return }; - // Ignore pure metadata/access noise; content changes are what matter. - if matches!(event.kind, notify::EventKind::Access(_)) { - return; - } - let msg = event_target(&watched_events.lock(), &event.paths); - let _ = tx_events.send(msg); - }) { - Ok(w) => w, + let handler = move |res: notify::Result| { + let event = match res { + Ok(event) => event, + // Running out of inotify watches for a new subfolder, say: that + // subfolder's changes are then found by the poll only (B262). Err(e) => { - warn!(error = %e, "filesystem watcher unavailable; sync is poll-only"); - // Still run the loop so polling and explicit SyncNow work. - poll_only_loop(&core, rx); + warn!(error = %e, "sync: filesystem watcher error"); return; } }; + // Ignore pure metadata/access noise; content changes are what matter. + if matches!(event.kind, notify::EventKind::Access(_)) { + return; + } + let msg = event_target(&watched_events.lock(), &event.paths); + let _ = tx_events.send(msg); + }; + // The local walk skips symlinks, so following them here would only watch + // trees outside the folder, and run passes over it for changes made there. + let config = notify::Config::default().with_follow_symlinks(false); + let mut watcher = match notify::RecommendedWatcher::new(handler, config) { + Ok(w) => w, + Err(e) => { + warn!(error = %e, "filesystem watcher unavailable; sync is poll-only"); + // Still run the loop so polling and explicit SyncNow work. + poll_only_loop(&core, rx); + return; + } + }; // Periodic remote poll. { @@ -218,8 +232,9 @@ fn engine_loop(core: Core, rx: Receiver) { .ok(); } - rewatch(&core, &mut watcher, &watched); - reconcile_all(&core); + let mut unwatched = rewatch(&core, &mut watcher, &watched); + let mut last_rewatch = Instant::now(); + run_burst(&core, &HashSet::new(), true); while let Ok(msg) = rx.recv() { let mut ids: HashSet = HashSet::new(); @@ -232,19 +247,16 @@ fn engine_loop(core: Core, rx: Receiver) { return; } + // A folder whose watch failed is tried again now and then, not only + // when the folder set changes. + if unwatched && last_rewatch.elapsed() >= REWATCH_RETRY { + do_rewatch = true; + } if do_rewatch { - rewatch(&core, &mut watcher, &watched); - } - if all { - reconcile_all(&core); - } else { - for id in ids { - if core.sync_paused() { - break; - } - run_pass_by_id(&core, id); - } + unwatched = rewatch(&core, &mut watcher, &watched); + last_rewatch = Instant::now(); } + run_burst(&core, &ids, all); } } @@ -261,7 +273,7 @@ fn poll_only_loop(core: &Core, rx: Receiver) { } }); } - reconcile_all(core); + run_burst(core, &HashSet::new(), true); while let Ok(msg) = rx.recv() { let mut ids: HashSet = HashSet::new(); let mut all = false; @@ -272,19 +284,59 @@ fn poll_only_loop(core: &Core, rx: Receiver) { info!("sync engine stopping"); return; } - if all { - reconcile_all(core); - } else { - for id in ids { - if core.sync_paused() { - break; - } - run_pass_by_id(core, id); + run_burst(core, &ids, all); + } +} + +/// Run the passes one burst asked for: the folders named by id, then, when the +/// burst also holds a `ReconcileAll`, every other folder. +/// +/// The named folders go first. A poll's `ReconcileAll` in the same burst used +/// to take their place, and a folder just added, which has the highest id, +/// waited behind a full pass over every other folder (`docs/BUGS.md` B260). +/// +/// Skipped while sync is paused, and cut short when a pause lands between +/// passes: the resume sends a fresh [`SyncMsg::ReconcileAll`], which walks +/// everything the watcher reported meanwhile. +fn run_burst(core: &Core, ids: &HashSet, all: bool) { + if core.sync_paused() { + debug!("sync: paused, skipping reconcile"); + return; + } + let folders = if all { + match core.db.sync_folder_list() { + Ok(folders) => folders, + Err(e) => { + warn!(error = ?e, "sync: cannot list folders"); + Vec::new() } } + } else { + Vec::new() + }; + let listed: Vec = folders.iter().map(|f| f.id).collect(); + for id in burst_order(ids, &listed) { + if core.sync_paused() { + break; + } + // A folder named by id is read again: it may have been added or + // changed after the list was read. + match folders.iter().find(|f| f.id == id) { + Some(folder) if !ids.contains(&id) => run_pass(core, folder), + _ => run_pass_by_id(core, id), + } } } +/// The order of a burst's passes: the folders named by id, lowest first, then +/// the rest of `listed` in its own order. +pub(super) fn burst_order(ids: &HashSet, listed: &[i64]) -> Vec { + let mut order: Vec = ids.iter().copied().collect(); + order.sort_unstable(); + order.extend(listed.iter().copied().filter(|id| !ids.contains(id))); + order +} + /// Absorb the rest of an event burst, returning once the watcher has been quiet /// for `quiet` or `cap` has elapsed since the first event — whichever comes /// first. The caller has already classified the event that opened the burst. @@ -356,26 +408,6 @@ pub(super) fn classify( true } -/// Reconcile every mirror folder in turn. Skipped while sync is paused: the -/// resume sends a fresh [`SyncMsg::ReconcileAll`], which walks everything the -/// watcher reported meanwhile. -fn reconcile_all(core: &Core) { - if core.sync_paused() { - debug!("sync: paused, skipping reconcile"); - return; - } - let folders = match core.db.sync_folder_list() { - Ok(f) => f, - Err(e) => { - warn!(error = ?e, "sync: cannot list folders"); - return; - } - }; - for folder in folders { - run_pass(core, &folder); - } -} - /// The reconcile a watcher event asks for: the one mirror folder all its paths /// lie in, so an edit in one folder does not walk every other one too. An event /// that spans folders, or that no watched folder claims (a watch list a moment @@ -396,7 +428,8 @@ pub(super) fn event_target(watched: &[(PathBuf, i64)], paths: &[PathBuf]) -> Syn } /// Bring the filesystem watches in line with the current mirror-folder set: -/// watch newly-added folders, drop removed ones. +/// watch newly-added folders, drop removed ones. Returns whether a folder is +/// left unwatched because its watch failed. /// /// The watch calls run on a copy, outside the lock: the watcher's event /// callback takes the same lock, and a backend that hands a watch request to @@ -405,7 +438,7 @@ fn rewatch( core: &Core, watcher: &mut notify::RecommendedWatcher, watched: &Mutex>, -) { +) -> bool { let want: Vec<(PathBuf, i64)> = match core.db.sync_folder_list() { Ok(f) => f .into_iter() @@ -414,30 +447,60 @@ fn rewatch( .collect(), Err(e) => { warn!(error = ?e, "sync: cannot list folders to watch"); - return; + return false; } }; let mut have = watched.lock().clone(); // Drop watches no longer wanted. - have.retain(|(path, _)| { - if want.iter().any(|(p, _)| p == path) { - true - } else { - let _ = watcher.unwatch(path); - false - } - }); + for path in keep_wanted(&mut have, &want) { + let _ = watcher.unwatch(&path); + } // Add newly wanted watches. + let mut failed = false; for (path, id) in &want { if have.iter().any(|(p, _)| p == path) { continue; } match watcher.watch(path, RecursiveMode::Recursive) { Ok(()) => have.push((path.clone(), *id)), - Err(e) => warn!(path = %path.display(), error = %e, "sync: watch failed"), + Err(e) => { + // A recursive watch that fails partway keeps the watches it had + // added. Their events would match no folder and run a pass over + // every one, and they hold watches the next folder needs (B262). + let _ = watcher.unwatch(path); + failed = true; + warn!( + path = %path.display(), + error = %e, + "sync: watch failed; the poll finds this folder's changes until a retry \ + works. A low fs.inotify.max_user_watches is the usual cause" + ); + } } } *watched.lock() = have; + failed +} + +/// Keep the watches in `have` that `want` still asks for, and return the paths +/// of the others, to unwatch. +/// +/// A path is matched alone, but takes the id `want` gives it: a folder removed +/// and added again in one burst keeps its watch, and its events go to the new +/// row rather than to the removed one (`docs/BUGS.md` B272). +pub(super) fn keep_wanted(have: &mut Vec<(PathBuf, i64)>, want: &[(PathBuf, i64)]) -> Vec { + let mut dropped = Vec::new(); + have.retain_mut(|(path, id)| match want.iter().find(|(p, _)| p == path) { + Some((_, wanted)) => { + *id = *wanted; + true + } + None => { + dropped.push(path.clone()); + false + } + }); + dropped } // ---- reconcile ------------------------------------------------------------ diff --git a/docs/BUGS.md b/docs/BUGS.md index 2103de3..9814d4e 100644 --- a/docs/BUGS.md +++ b/docs/BUGS.md @@ -69,7 +69,6 @@ original wording. | Entry | Title | What is left | |---|---|---| | [B273](#b273--a-restore-proposes-another-computers-paths-when-the-two-share-a-hostname) | A restore proposes another computer's paths when the two share a hostname | Not fixed | -| [B272](#b272--after-a-folder-is-removed-and-added-again-its-file-events-go-to-the-old-id) | After a folder is removed and added again, its file events go to the old id | Not fixed | | [B271](#b271--one-failed-listing-makes-a-large-first-sync-start-over-from-nothing) | One failed listing makes a large first sync start over from nothing | Not fixed | | [B270](#b270--one-file-left-in-a-mirror-folder-clears-the-wipe-guard-for-all-the-others) | One file left in a mirror folder clears the wipe guard for all the others | Not fixed | | [B269](#b269--a-restore-that-skipped-every-folder-reports-success) | A restore that skipped every folder reports success | Not fixed | @@ -79,9 +78,7 @@ original wording. | [B265](#b265--address-keys-whose-token-is-for-an-inactive-account-key-never-open) | Address keys whose token is for an inactive account key never open | Needs an SDK change; not reproduced | | [B264](#b264--a-mount-that-fails-after-starting-its-workers-leaves-them-running) | A mount that fails after starting its workers leaves them running | Not fixed | | [B263](#b263--a-mount-that-can-never-succeed-retries-every-5-s-and-tells-only-the-journal) | A mount that can never succeed retries every 5 s and tells only the journal | Not fixed | -| [B262](#b262--watching-a-large-synced-folder-holds-up-the-sync-engine-and-a-failed-watch-is-never-retried) | Watching a large synced folder holds up the sync engine, and a failed watch is never retried | Not fixed | | [B261](#b261--a-folder-that-has-never-synced-reads-up-to-date) | A folder that has never synced reads "up to date" | Not fixed | -| [B260](#b260--the-poll-pushes-a-new-folders-first-sync-behind-every-other-folder) | The poll pushes a new folder's first sync behind every other folder | Not fixed | | [B258](#b258--journalctl--p-warning-shows-nothing-whatever-the-daemon-logged) | `journalctl -p warning` shows nothing, whatever the daemon logged | Not fixed | | [B134](#b134--a-file-deleted-online-while-the-drain-checks-its-write-is-kept-as-a-conflict-copy) | A file deleted online while the drain checks its write is kept as a conflict copy | Only with `local_first` off | | [B91](#b91--the-daemon-hung-overnight-and-nothing-could-say-what-it-was-waiting-on) | The daemon hung overnight, and nothing could say what it was waiting on | The cause is not diagnosed; the daemon now reports where it is stuck and is restarted | @@ -95,6 +92,7 @@ original wording. | Entry | Title | What is left | |---|---|---| +| [B262](#b262--watching-a-large-synced-folder-holds-up-the-sync-engine-and-a-failed-watch-is-never-retried) | Watching a large synced folder holds up the sync engine, and a failed watch is never retried | The first pass still waits for the watch; a failed watch is not shown in the app | | [B259](#b259--the-sync-engine-can-die-or-hang-and-nothing-shows-it-until-a-restart) | The sync engine can die or hang, and nothing shows it until a restart | No pass deadline; an ended engine is reported, not restarted; the trigger in #53 is not known | | [B199](#b199--a-stopped-share-stays-on-the-shared-by-me-page-for-minutes) | A stopped share stays on the Shared by me page for minutes | The share itself is not deleted; the SDK has no call for it | | [B88](#b88--pdfs-pin-rename-move-delete-and-sharing-still-cannot-name-a-path-under-a-secondary-mount) | `pdfs pin`, `rename`, `move`, `delete` and sharing still cannot name a path under a secondary mount | `pin`, `unpin`, opening a file, thumbnails, uploads, sharing and versions | @@ -116,6 +114,8 @@ a live account since. | Entry | Title | |---|---| +| [B272](#b272--after-a-folder-is-removed-and-added-again-its-file-events-go-to-the-old-id) | After a folder is removed and added again, its file events go to the old id | +| [B260](#b260--the-poll-pushes-a-new-folders-first-sync-behind-every-other-folder) | The poll pushes a new folder's first sync behind every other folder | | [B256](#b256--pdfs-copy-right-after-a-save-copies-the-old-version) | `pdfs copy` right after a save copies the old version | | [B255](#b255--a-synced-folder-whose-files-are-all-gone-here-is-stuck-for-good) | A synced folder whose files are all gone here is stuck for good | | [B254](#b254--an-edit-in-the-same-second-as-a-new-upload-never-arrives) | An edit in the same second as a new upload never arrives | @@ -395,7 +395,7 @@ written before it existed. ### B272 — After a folder is removed and added again, its file events go to the old id -**Status:** Open +**Status:** Fixed, not verified live **Found:** 2026-10-31, code audit after issue #53. **Where:** `rewatch` in `crates/pdfs-fuse/src/sync/engine.rs` @@ -407,8 +407,10 @@ two-minute poll, and the same goes for every later edit until the daemon restart path is still wanted, so the old entry stays with the removed folder's id. Its events become `Reconcile(old id)`, `sync_folder_get` finds no row, and the request is dropped. -**Fix.** Not done. Compare `(path, id)` pairs, and update the id of a path that is still -watched. +**Fix.** `keep_wanted` keeps a watch whose path is still wanted and gives it the id the +folder list has now. + +**Test:** `a_re_added_folder_keeps_its_watch_under_the_new_id` in `pdfs-fuse`. --- @@ -613,7 +615,8 @@ show it (a state file, and `STATUS=` to systemd). ### B262 — Watching a large synced folder holds up the sync engine, and a failed watch is never retried -**Status:** Open +**Status:** Partly fixed. A watch is still set up before the first pass, and a failed watch +is not shown in the folder's state. **Found:** 2026-10-31, code audit after issue #53. **Where:** `rewatch` and `engine_loop` in `crates/pdfs-fuse/src/sync/engine.rs` @@ -631,8 +634,16 @@ line, the folder is never watched, and later changes are found only by the two-m and they use up watches the next folder needs. - Errors the watcher reports later are dropped in its callback. -**Fix.** Not done. Reconcile first, unwatch after a partial failure and retry with a back-off, -turn off symlink following, and show a watch failure in the folder's state. +**Fix.** +- A failed watch is unwatched, which removes the watches it had added under the folder, and + is tried again every 10 minutes. The warning names `fs.inotify.max_user_watches`. +- The watcher no longer follows symlinks. +- Errors the watcher reports are logged. +- Not done: the watch still runs before the folder's first pass. Watching first is what keeps + a change made during the pass from being missed, so the order stays; the cost is one walk + of a new folder's tree. A failed watch is not shown in the folder's state yet. + +**Test:** none for the watch failure itself; it needs the inotify limit reached. --- @@ -660,7 +671,7 @@ account-wide pause on the folder rows. ### B260 — The poll pushes a new folder's first sync behind every other folder -**Status:** Open +**Status:** Fixed, not verified live **Found:** 2026-10-31, code audit after issue #53. **Where:** `engine_loop` in `crates/pdfs-fuse/src/sync/engine.rs` @@ -673,8 +684,11 @@ running. When a burst holds both a `ReconcileAll` and a folder's `Reconcile(id)` only `reconcile_all`, which goes in id order. A new folder has the highest id, so it always goes last. -**Fix.** Not done. Run the folders asked for by id before the rest, and don't queue a poll -while a pass runs. +**Fix.** `run_burst` runs the folders a burst names by id first, lowest id first, and then +every other folder when the burst also holds a `ReconcileAll`. A named folder is read again +before its pass. A pause that lands between passes now stops the rest of the burst. + +**Test:** `named_folders_run_before_the_rest_of_a_burst` in `pdfs-fuse`. ---